Skip to content

fix(logger): reduce logging overhead on request threads#41

Open
Trojan-254 wants to merge 1 commit intoAz107:masterfrom
Trojan-254:master
Open

fix(logger): reduce logging overhead on request threads#41
Trojan-254 wants to merge 1 commit intoAz107:masterfrom
Trojan-254:master

Conversation

@Trojan-254
Copy link
Copy Markdown
Contributor

fix(logger): reduce logging overhead on request threads

Problem

Despite the logger running in a background thread, logging was introducing measurable latency on the request-handling path. Benchmarks showed a ~32% throughput drop and near 2x latency increase when logging was enabled:

  Requests/sec Avg Latency
Without logs 114,971 719µs
With logs 78,739 1.19ms

Root Causes

  • SimpleTime::get_current_timestamp() was called on the request thread per log message, performing a syscall, a year-loop calendar calculation, and a format! allocation before the message even reached the channel
  • (*self.component).clone() was heap-allocating a new String on every log call despite component already being an Arc<String>
  • format!() at call sites allocated unconditionally before the log level filter could discard the message
  • channel() (unbounded) was used with blocking send(), which could synchronize request threads with the logger under load
  • Log level was hardcoded to DEBUG/INFO via cfg!(debug_assertions) with no way to suppress logging at runtime

Changes

logger.rs

  • Timestamp moved to the logger thread - SimpleTime::get_current_timestamp() is now called inside the consumer loop, completely off the request path
  • Arc::clone instead of String::clone - LogMessage.component is now Arc<String>, making the clone a single atomic increment
  • sync_channel(4096) replaces channel() - pre-allocated ring buffer with no growth allocations
  • try_send() replaces send() - drops messages under saturation rather than blocking the request thread
  • Lazy-format macros log_info!, log_debug!, log_warn!, log_error! - check the log level before calling format!(), so filtered messages produce zero allocations
  • Logger::enabled() - exposes the level check cleanly for use by macros without making min_level public

config.rs

  • Added log_level: Option<String> field to the Config struct
  • Parsed from the [HTEAPOT] section in config.toml
  • Defaults to None, falling back to the existing cfg!(debug_assertions) behaviour when not set

main.rs

  • min_log now resolves from config.log_level first, with cfg!(debug_assertions) as the fallback
  • All logger.xxx(format!(...)) call sites replaced with the lazy macros

Configuration

Log level can now be controlled at runtime via config.toml:

[HTEAPOT]
log_level = "none"   # "debug" | "info" | "warn" | "error" | "none"

Setting "none" suppresses all log output with zero allocation overhead on the request path.

Notes

Under extreme load, try_send will silently drop log entries when the channel buffer is full. This is intentional, log loss under saturation is preferable to request thread stalls. The 4096-entry buffer provides ample headroom for normal operation.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant